HylaFAX The world's most advanced open source fax server
[Date Prev][Date Next][Thread Prev][Thread Next] [Date Index] [Thread Index]

Re: [hylafax-users] modem (or faxgetty?) hangs "receiving from ..." STRACE AND LOG

Aidan Van Dyk wrote:
* Patrick Fromberg <patrick.fromberg@xxxxxxxxx> [031205 15:14]:

/usr/sbin/strace -tt -p XXXX
  where XXXX is the process id of the stuck faxgetty process.

16:01:56.727457 rt_sigaction(SIGALRM, {0x400a0b10, [], SA_RESTORER|SA_INTERRUPT, 0x4029a5c8}, NULL, 8) = 0
16:01:56.727711 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={180, 0}}, NULL) = 0
16:01:56.727809 gettimeofday({1070895716, 727838}, NULL) = 0
16:01:56.727896 write(9, "Dec 08 16:01:56.72: [ 5284]: awa"..., 92) = 92
16:01:56.728001 gettimeofday({1070895716, 728030}, NULL) = 0
16:01:56.728080 write(9, "Dec 08 16:01:56.72: [ 5284]: no "..., 63) = 63
16:01:56.728160 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
16:01:56.728234 gettimeofday({1070895716, 728263}, NULL) = 0
16:01:56.728313 write(9, "Dec 08 16:01:56.72: [ 5284]: -->"..., 55) = 55
16:01:56.728410 rt_sigaction(SIGALRM, {0x400a0b10, [], SA_RESTORER|SA_INTERRUPT, 0x4029a5c8}, NULL, 8) = 0
16:01:56.728491 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0
16:01:56.728566 gettimeofday({1070895716, 728594}, NULL) = 0
16:01:56.728644 write(9, "Dec 08 16:01:56.72: [ 5284]: awa"..., 91) = 91
16:01:56.728725 read(7, "\r\n+FET:0\r\nOK\r\n\r\n+FHS:A0\r\n\r\nOK\r\n\r"..., 1024) = 55
16:01:56.822810 gettimeofday({1070895716, 822839}, NULL) = 0
16:01:56.822889 write(9, "Dec 08 16:01:56.82: [ 5284]: no "..., 63) = 63
16:01:56.822971 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
16:01:56.823045 gettimeofday({1070895716, 823073}, NULL) = 0
16:01:56.823122 write(9, "Dec 08 16:01:56.82: [ 5284]: -->"..., 44) = 44
16:01:56.823210 gettimeofday({1070895716, 823239}, NULL) = 0
16:01:56.823288 write(9, "Dec 08 16:01:56.82: [ 5284]: REC"..., 71) = 71
16:01:56.823370 rt_sigaction(SIGALRM, {0x400a0b10, [], SA_RESTORER|SA_INTERRUPT, 0x4029a5c8}, NULL,, 0}, it_value={30, 0}}, NULL) = 0
16:01:56.823522 gettimeofday({1070895716, 823550}, NULL) = 0
16:01:56.823600 write(9, "Dec 08 16:01:56.82: [ 5284]: awa"..., 91) = 91
16:01:56.823681 gettimeofday({1070895716, 823709}, NULL) = 0
16:01:56.823758 write(9, "Dec 08 16:01:56.82: [ 5284]: no "..., 63) = 63
16:01:56.823838 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
16:01:56.823907 gettimeofday({1070895716, 823930}, NULL) = 0
16:01:56.823974 write(9, "Dec 08 16:01:56.82: [ 5284]: -->"..., 40) = 40
16:01:56.824046 gettimeofday({1070895716, 824069}, NULL) = 0
16:01:56.824107 select(8, [4 7], [], [7], {0, 0}) = 0 (Timeout)
16:01:56.824238 gettimeofday({1070895716, 824261}, NULL) = 0
16:01:56.824301 lseek(10, 0, SEEK_END) = 30213
16:01:56.824362 lseek(10, = 2
16:01:56.824492 lseek(10, 312, SEEK_CUR) = 15530
16:01:56.824547 read(10, "\0\0\0\0", 4) = 4
16:01:56.824608 lseek(10, 0, SEEK_CUR) = 15534
16:01:56.824664 lseek(10, 15530, SEEK_SET) = 15530
16:01:56.824719 write(10, "\6v\0\0", 4) = 4
16:01:56.824784 lseek(10, 30532, SEEK_SET) = 30532
16:01:56.824844 lseek(10, 30532, SEEK_SET) = 30532
16:01:56.824899 write(10, "\"ELSA, AACHEN (GERMANY)\"\0", 25) = 25
16:01:56.824967 lseek(10, 30558, SEEK_SET) = 30558
16:01:56.825022 write(10, "\"MicroLink 28.8TQV\"\0", 20) = 20
16:01:56.825092 lseek(10, 30578, SEEK_SET) = 30578
16:01:56.825148 write(10, "\0\0\200\31\0\0 \0", 8) = 8
16:01:56.825216 lseek(10, 30586, SEEK_SET) = 30586
16:01:56.825271 write(10, "\0\0\0b\0\0\0\1", 8) = 8
16:01:56.825338 lseek(10, 30594, SEEK_SET) = 30594
16:01:56.825394 write(10, "HylaFAX (tm) Version 4.1.7\0", 27) = 27
16:01:56.825460 lseek(10, 30622, SEEK_SET) = 30622
16:01:56.825516 write(10, "2003:12:08 15:02:31\0", 20) = 20
16:01:56.825583 lseek(10, 30214, SEEK_SET) = 30214
16:01:56.825639 write(10, "\32\0", 2) = 2
16:01:56.825698 write(10, "\376\0\4\0\1\0\0\0\2\0\0\0\0\1\3\0\1\0\0\0\300\6\0\0\1"..., 312) = 312
16:01:56.825777 write(10, "\0\0\0\0", 4) = 4
16:01:56.825870 gettimeofday({1070895716, 825894}, NULL) = 0
16:01:56.825940 write(9, "Dec 08 16:01:56.82: [ 5284]: REC"..., 66) = 66
16:01:56.826010 time(NULL) = 1070895716
16:01:56.826075 write(6, "@ttyS0:Pdf0,2,242028,recvq/fax00"..., 58) = 58
16:01:56.826178 time([1070895716]) = 1070895716
16:01:56.826242 getpid() = 5284
16:01:56.826301 rt_sigaction(SIGPIPE, {0x4034f420, [], SA_RESTORER, 0x4029a5c8}, {SIG_IGN}, 8) = 0
16:01:56.826377 send(5, "<30>Dec 8 16:01:56 FaxGetty[528"..., 119, 0) = 119
16:01:56.826501 rt_sigaction(SIGPIPE, {SIG_IGN}, NULL, 8) = 0
16:01:56.826563 gettimeofday({1070895716, 826585}, NULL) = 0
16:01:56.826633 write(9, "Dec 08 16:01:56.82: [ 5284]: REC"..., 113) = 113
16:01:56.826702 time(NULL) = 1070895716
16:01:56.826764 gettimeofday({1070895716, 826787}, NULL) = 0
16:01:56.826831 write(9, "Dec 08 16:01:56.82: [ 5284]: <--"..., 46) = 46
16:01:56.826929 write(7, "AT+FDR", 6) = 6
16:01:56.826989 write(7, "\r", 1) = 1
16:01:56.827050 rt_sigaction(SIGALRM, {0x400a0b10, [], SA_RESTORER|SA_INTERRUPT, 0x4029a5c8}, NULL, 8) = 0
16:01:56.827118 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={180, 0}}, NULL) = 0
16:01:56.827187 gettimeofday({1070895716, 827210}, NULL) = 0
16:01:56.827255 write(9, "Dec 08 16:01:56.82: [ 5284]: awa"..., 92) = 92
16:01:56.827327 gettimeofday({1070895716, 827350}, NULL) = 0
16:01:56.827394 write(9, "Dec 08 16:01:56.82: [ 5284]: no "..., 63) = 63
16:01:56.827464 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
16:01:56.827527 gettimeofday({1070895716, 827550}, NULL) = 0
16:01:56.827594 write(9, "Dec 08 16:01:56.82: [ 5284]: -->"..., 45) = 45
16:01:56.827670 gettimeofday({1070895716, 827693}, NULL) = 0
16:01:56.827737 write(9, "Dec 08 16:01:56.82: [ 5284]: REM"..., 80) = 80
16:01:56.827811 close(10) = 0
16:01:56.827868 time(NULL) = 1070895716
16:01:56.827934 write(6, "@ttyS0:De00,2,242028,recvq/faxn(SIGPIPE, {0x4034f420, [], SA_RESTORER, 0x4029a5c8}, {SIG_IGN}, 8) = 0
16:01:56.828223 send(5, "<30>Dec 8 16:01:56 FaxGetty[528"..., 123, 0) = 123
16:01:56.828324 rt_sigaction(SIGPIPE, {SIG_IGN}, NULL, 8) = 0
16:01:56.828386 gettimeofday({1070895716, 828409}, NULL) = 0
16:01:56.828455 write(9, "Dec 08 16:01:56.82: [ 5284]: REC"..., 117) = 117
16:01:56.828525 time(NULL) _RDWR|O_APPEND|O_CREAT, 0644) = 8
16:01:56.828683 flock(8, LOCK_EX) = 0
16:01:56.828743 write(8, "12/08/03 15:02\tRECV\t00000199\ttty"..., 115) = 115
16:01:56.828816 close(8) = 0
16:01:56.828875 gettimeofday({1070895716, 828899}, NULL) = 0
16:01:56.828943 write(9, "Dec 08 16:01:56.82: [ 5284]: REC"..., 65) = 65
16:01:56.829013 chmod("recvq/fax00112.tif", 0600) = 0
16:01:56.829094 time([1070895716]) = 1070895716
16:01:56.829157 getpid() = 5284
16:01:56.829216 rt_sigaction(SIGPIPE, {0x4034f420, [], SA_RESTORER, 0x4029a5c8}, {SIG_IGN}, 8) = 0
16:01:56.829291 send(5, "<30>Dec 8 16:01:56 FaxGetty[528"..., 119, 0) = 119
16:01:56.829390 rt_sigaction(SIGPIPE, {SIG_IGN}, NULL, 8) = 0
16:01:56.829451 gettimeofday({1070895716, 829474}, NULL) = 0
16:01:56.829520 write(9, "Dec 08 16:01:56.82: [ 5284]: REC"..., 113) = 113
16:01:56.829598 time([1070895716]) = 1070895716
16:01:56.829659 getpid() = 5284
16:01:56.829717 rt_sigaction(SIGPIPE, {0x4034f420, [], SA_RESTORER, 0x4029a5c8}, {SIG_IGN}, 8) = 0
16:01:56.829791 send(5, "<30>Dec 8 16:01:56 FaxGetty[528"..., 134, 0) = 134
16:01:56.829883 rt_sigaction(SIGPIPE, {SIG_IGN}, NULL, 8) = 0
16:01:56.829944 gettimeofday({1070895716, 829967}, NULL) = 0
16:01:56.830013 write(9, "Dec 08 16:01:56.82: [ 5284]: REC"..., 128) = 128
16:01:56.830086 fork() = 19622
160], 0, NULL) = 19622
16:01:57.051599 --- SIGCHLD (Child exited) @ 0 (0) ---
16:01:57.051684 gettimeofday({1070895717, 51709}, NULL) = 0
16:01:57.051767 write(9, "Dec 08 16:01:57.05: [ 5284]: REC"..., 43) = 43
16:01:57.051864 write(6, "@ttyS0:E\0", 9) = 9
16:01:57.051960 write(6, "+ttyS0:I\0", 9) = 9
16:01:57.052036 gettimeofday({1070895717, 52060}, NULL) = 0
16:01:57.052106 write(9, "Dec 08 16:01:57.05: [ 5284]: SES"..., 41) = 41
16:01:57.052176 close(9) = 0
16:01:57.052240 write(7, "ATH0", 4) = 4
16:01:57.052300 write(7, "\r", 1) = 1
16:01:57.052363 rt_sigaction(SIGALRM, {0x400a0b10, [], SA_RESTORER|SA_INTERRUPT, 0x4029a5c8}, NULL, 8) = 0
16:01:57.052434 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={5, 0}}, NULL) = 0
16:01:57.052501 setitimer(ITIMER_REAL, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
16:01:57.052575 ioctl(7, TIOCMBIC, [TIOCM_DTR]) = 0
16:01:57.052647 close(7 <unfinished ...>






and here the log

Dec 08 15:02:02.59: [ 5284]: SESSION BEGIN 00000199 498944429004
Dec 08 15:02:02.59: [ 5284]: HylaFAX (tm) Version 4.1.7
Dec 08 15:02:02.59: [ 5284]: <-- [4:ATA\r]
Dec 08 15:02:02.59: [ 5284]: awaiting characters from the modem - will timeout in 180000 ms
Dec 08 15:02:12.04: [ 5284]: no longer awaiting modem response
Dec 08 15:02:12.04: [ 5284]: --> [4:+FCO]
Dec 08 15:02:12.04: [ 5284]: ANSWER: FAX CONNECTION DEVICE '/dev/ttyS0'
Dec 08 15:02:12.04: [ 5284]: RECV FAX: begin
Dec 08 15:02:12.04: [ 5284]: RECV FAX: CDPN
Dec 08 15:02:12.04: [ 5284]: awaiting characters from the modem - will timeout in 180000 ms
Dec 08 15:02:16.42: [ 5284]: no longer awaiting modem response
Dec 08 15:02:16.42: [ 5284]: --> [7:+FTI:""]
Dec 08 15:02:16.42: [ 5284]: REMOTE TSI ""
Dec 08 15:02:16.42: [ 5284]: awaiting characters from the modem - will timeout in 180000 ms
Dec 08 15:02:16.42: [ 5284]: no longer awaiting modem response
Dec 08 15:02:16.42: [ 5284]: --> [20:+FCS:0,5,0,2,0,0,0,1]
Dec 08 15:02:16.42: [ 5284]: REMOTE wants 14400 bit/s
Dec 08 15:02:16.42: [ 5284]: REMOTE wants page width 1728 pixels in 215 mm
Dec 08 15:02:16.42: [ 5284]: REMOTE wants unlimited page length
Dec 08 15:02:16.42: [ 5284]: REMOTE wants 3.85 line/mm
Dec 08 15:02:16.42: [ 5284]: REMOTE wants 1-D MR
Dec 08 15:02:16.42: [ 5284]: awaiting characters from the modem - will timeout in 180000 ms
Dec 08 15:02:16.42: [ 5284]: no longer awaiting modem response
Dec 08 15:02:16.42: [ 5284]: --> [2:OK]
Dec 08 15:02:16.42: [ 5284]: <-- [7:AT+FDR\r]
Dec 08 15:02:16.42: [ 5284]: awaiting characters from the modem - will timeout in 180000 ms
Dec 08 15:02:18.67: [ 5284]: no longer awaiting modem response
Dec 08 15:02:18.67: [ 5284]: --> [7:CONNECT]
Dec 08 15:02:18.67: [ 5284]: RECV: begin page
Dec 08 15:02:18.67: [ 5284]: RECV: send trigger 022
Dec 08 15:02:18.67: [ 5284]: <-- data [1]
Dec 08 15:02:27.55: [ 5284]: RECV: 15208 bytes of data, 556 total lines
Dec 08 15:02:27.55: [ 5284]: awaiting characters from the modem - will timeout in 180000 ms
Dec 08 15:02:27.55: [ 5284]: no longer awaiting modem response
Dec 08 15:02:27.55: [ 5284]: --> [16:+FPS:1,233,0,0,0]
Dec 08 15:02:27.55: [ 5284]: awaiting characters from the modem - will timeout in 30000 ms
Dec 08 15:02:28.83: [ 5284]: no longer awaiting modem response
Dec 08 15:02:28.83: [ 5284]: --> [6:+FET:0]
Dec 08 15:02:28.83: [ 5284]: RECV recv MPS (more pages, same document)
Dec 08 15:02:28.83: [ 5284]: awaiting characters from the modem - will timeout in 30000 ms
Dec 08 15:02:28.83: [ 5284]: no longer awaiting modem response
Dec 08 15:02:28.83: [ 5284]: --> [2:OK]
Dec 08 15:02:28.83: [ 5284]: RECV send MCF (message confirmation)
Dec 08 15:02:28.83: [ 5284]: RECV FAX (00000199): from , page 1 in 0:12, INF, 3.85 line/mm, 1-D MR, 14400 bit/s
Dec 08 15:02:28.83: [ 5284]: <-- [7:AT+FDR\r]
Dec 08 15:02:28.83: [ 5284]: awaiting characters from the modem - will timeout in 180000 ms
Dec 08 15:02:31.30: [ 5284]: no longer awaiting modem response
Dec 08 15:02:31.30: [ 5284]: --> [7:CONNECT]
Dec 08 15:02:31.30: [ 5284]: RECV: begin page
Dec 08 15:02:31.30: [ 5284]: RECV: send trigger 022
Dec 08 15:02:31.30: [ 5284]: <-- data [1]
Dec 08 15:02:39.82: [ 5284]: RECV: 14569 bytes of data, 554 total lines
Dec 08 16:01:56.72: [ 5284]: awaiting characters from the modem - will timeout in 180000 ms
Dec 08 16:01:56.72: [ 5284]: no longer awaiting modem response
Dec 08 16:01:56.72: [ 5284]: --> [16:+FPS:1,231,0,0,0]
Dec 08 16:01:56.72: [ 5284]: awaiting characters from the modem - will timeout in 30000 ms
Dec 08 16:01:56.82: [ 5284]: no longer awaiting modem response
Dec 08 16:01:56.82: [ 5284]: --> [6:+FET:0]
Dec 08 16:01:56.82: [ 5284]: RECV recv MPS (more pages, same document)
Dec 08 16:01:56.82: [ 5284]: awaiting characters from the modem - will timeout in 30000 ms
Dec 08 16:01:56.82: [ 5284]: no longer awaiting modem response
Dec 08 16:01:56.82: [ 5284]: --> [2:OK]
Dec 08 16:01:56.82: [ 5284]: RECV send MCF (message confirmation)
Dec 08 16:01:56.82: [ 5284]: RECV FAX (00000199): from , page 2 in 59:28, INF, 3.85 line/mm, 1-D MR, 14400 bit/s
Dec 08 16:01:56.82: [ 5284]: <-- [7:AT+FDR\r]
Dec 08 16:01:56.82: [ 5284]: awaiting characters from the modem - will timeout in 180000 ms
Dec 08 16:01:56.82: [ 5284]: no longer awaiting modem response
Dec 08 16:01:56.82: [ 5284]: --> [7:+FHS:A0]
Dec 08 16:01:56.82: [ 5284]: REMOTE HANGUP: Unspecified Phase D error (code A0)
Dec 08 16:01:56.82: [ 5284]: RECV FAX (00000199): recvq/fax00112.tif from , route to <unspecified>, 2 pages in 59:44
Dec 08 16:01:56.82: [ 5284]: RECV FAX: Unspecified Phase D error
Dec 08 16:01:56.82: [ 5284]: RECV FAX (00000199): session with terminated abnormally: Unspecified Phase D error
Dec 08 16:01:56.82: [ 5284]: RECV FAX: bin/faxrcvd "recvq/fax00112.tif" "ttyS0" "00000199" "Unspecified Phase D error" "" "" ""
Dec 08 16:01:57.05: [ 5284]: RECV FAX: end
Dec 08 16:01:57.05: [ 5284]: SESSION END



--
Patrick

____________________ HylaFAX(tm) Users Mailing List _______________________
 To subscribe/unsubscribe, click http://lists.hylafax.org/cgi-bin/lsg2.cgi
On UNIX: mail -s unsubscribe hylafax-users-request@xxxxxxxxxxx < /dev/null
 *To learn about commercial HylaFAX(tm) support, mail sales@xxxxxxxxxxxx*

Project hosted by iFAX Solutions