Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Write does not seem to complete correctly #10

Open
Craige opened this issue Feb 26, 2021 · 13 comments
Open

Write does not seem to complete correctly #10

Craige opened this issue Feb 26, 2021 · 13 comments

Comments

@Craige
Copy link

Craige commented Feb 26, 2021

When writing a track, it appears to not finalize the write properly. My NetMD device seems to be waiting for something else from the host that isn't sent.

➜  netmdcli git:(master) ✗ ./netmdcli -v send ~/Desktop/Track.wav
Net MD Walkman
Raw title:
Disc Title: <Untitled>

audio file size : 39522976 bytes
supported audio file detected
data chunk position at 152
audio data size read from file :           39522816 bytes
audio data size calculated from file size: 39522816 bytes
netmd_acquire_dev: Unknown Error
netmd_secure_leave_session : No error
netmd_secure_set_track_protection : No error
netmd_secure_enter_session : No error
netmd_secure_send_key_data : No error
netmd_secure_session_key_exchange : No error
netmd_secure_setup_download : No error
generating packet 1 : 1048552 bytes
generating packet 2 : 1048576 bytes
generating packet 3 : 1048576 bytes
generating packet 4 : 1048576 bytes
generating packet 5 : 1048576 bytes
generating packet 6 : 1048576 bytes
generating packet 7 : 1048576 bytes
generating packet 8 : 1048576 bytes
generating packet 9 : 1048576 bytes
generating packet 10 : 1048576 bytes
generating packet 11 : 1048576 bytes
generating packet 12 : 1048576 bytes
generating packet 13 : 1048576 bytes
generating packet 14 : 1048576 bytes
generating packet 15 : 1048576 bytes
generating packet 16 : 1048576 bytes
generating packet 17 : 1048576 bytes
generating packet 18 : 1048576 bytes
generating packet 19 : 1048576 bytes
generating packet 20 : 1048576 bytes
generating packet 21 : 1048576 bytes
generating packet 22 : 1048576 bytes
generating packet 23 : 1048576 bytes
generating packet 24 : 1048576 bytes
generating packet 25 : 1048576 bytes
generating packet 26 : 1048576 bytes
generating packet 27 : 1048576 bytes
generating packet 28 : 1048576 bytes
generating packet 29 : 1048576 bytes
generating packet 30 : 1048576 bytes
generating packet 31 : 1048576 bytes
generating packet 32 : 1048576 bytes
generating packet 33 : 1048576 bytes
generating packet 34 : 1048576 bytes
generating packet 35 : 1048576 bytes
generating packet 36 : 1048576 bytes
generating packet 37 : 1048576 bytes
last packet: packet_data_length=725528 + frame_padding=1536 = chunksize=727064
generating packet 38 : 727064 bytes
netmd_prepare_packets : No error
total transfer size : 39524376 bytes, 19299 frames of 2048 bytes
1048576 of 39524376 bytes (2%) transferred (1048576 of 1048576 bytes in packet)
2097152 of 39524376 bytes (5%) transferred (1048576 of 1048576 bytes in packet)
3145728 of 39524376 bytes (7%) transferred (1048576 of 1048576 bytes in packet)
4194304 of 39524376 bytes (10%) transferred (1048576 of 1048576 bytes in packet)
5242880 of 39524376 bytes (13%) transferred (1048576 of 1048576 bytes in packet)
6291456 of 39524376 bytes (15%) transferred (1048576 of 1048576 bytes in packet)
7340032 of 39524376 bytes (18%) transferred (1048576 of 1048576 bytes in packet)
8388608 of 39524376 bytes (21%) transferred (1048576 of 1048576 bytes in packet)
9437184 of 39524376 bytes (23%) transferred (1048576 of 1048576 bytes in packet)
10485760 of 39524376 bytes (26%) transferred (1048576 of 1048576 bytes in packet)
11534336 of 39524376 bytes (29%) transferred (1048576 of 1048576 bytes in packet)
12582912 of 39524376 bytes (31%) transferred (1048576 of 1048576 bytes in packet)
13631488 of 39524376 bytes (34%) transferred (1048576 of 1048576 bytes in packet)
14680064 of 39524376 bytes (37%) transferred (1048576 of 1048576 bytes in packet)
15728640 of 39524376 bytes (39%) transferred (1048576 of 1048576 bytes in packet)
16777216 of 39524376 bytes (42%) transferred (1048576 of 1048576 bytes in packet)
17825792 of 39524376 bytes (45%) transferred (1048576 of 1048576 bytes in packet)
18874368 of 39524376 bytes (47%) transferred (1048576 of 1048576 bytes in packet)
19922944 of 39524376 bytes (50%) transferred (1048576 of 1048576 bytes in packet)
20971520 of 39524376 bytes (53%) transferred (1048576 of 1048576 bytes in packet)
22020096 of 39524376 bytes (55%) transferred (1048576 of 1048576 bytes in packet)
23068672 of 39524376 bytes (58%) transferred (1048576 of 1048576 bytes in packet)
24117248 of 39524376 bytes (61%) transferred (1048576 of 1048576 bytes in packet)
25165824 of 39524376 bytes (63%) transferred (1048576 of 1048576 bytes in packet)
26214400 of 39524376 bytes (66%) transferred (1048576 of 1048576 bytes in packet)
27262976 of 39524376 bytes (68%) transferred (1048576 of 1048576 bytes in packet)
28311552 of 39524376 bytes (71%) transferred (1048576 of 1048576 bytes in packet)
29360128 of 39524376 bytes (74%) transferred (1048576 of 1048576 bytes in packet)
30408704 of 39524376 bytes (76%) transferred (1048576 of 1048576 bytes in packet)
31457280 of 39524376 bytes (79%) transferred (1048576 of 1048576 bytes in packet)
32505856 of 39524376 bytes (82%) transferred (1048576 of 1048576 bytes in packet)
33554432 of 39524376 bytes (84%) transferred (1048576 of 1048576 bytes in packet)
34603008 of 39524376 bytes (87%) transferred (1048576 of 1048576 bytes in packet)
35651584 of 39524376 bytes (90%) transferred (1048576 of 1048576 bytes in packet)
36700160 of 39524376 bytes (92%) transferred (1048576 of 1048576 bytes in packet)
37748736 of 39524376 bytes (95%) transferred (1048576 of 1048576 bytes in packet)
38797312 of 39524376 bytes (98%) transferred (1048576 of 1048576 bytes in packet)
39524376 of 39524376 bytes (100%) transferred (727064 of 727064 bytes in packet)
netmd_transfer_song_packets : transfer took 112 seconds (344 kB/sec)
netmd_secure_send_track : No error
New Track: 0
netmd_exch_message: netmd_poll failed
netmd_secure_commit_track failed : Unknown Error
netmd_secure_session_key_forget : No error
netmd_secure_leave_session : No error
netmd_release_dev : Unknown Error

Everything seems to work up until New Track: 0, at which point my device flashes Edit, and the applications seems to halt. After several seconds, netmdcliresponds with the rest of the log above, and the device is stuck in write mode with Edit on the display. In some cases, if I kill power to the device the track appears to be written and can play but might be corrupt leading to problems with reading when re-staring the device (the longer the device is powerd up, the longer it takes for the device to read the disk when it re-starts) It seems like the device just continues writing garbage after netmdcli kills the connection.

If I do manage to successfully write a single track, I can't seem to write subsequent tracks at any point after without erasing the disk.

Device is a MZ-N420D for what it's worth.

@vuori
Copy link
Owner

vuori commented Feb 26, 2021

Could you try to comment out netmd_set_title(devh, track, titlep); and/or netmd_sync_toc(devh); around line 972 of netmdcli.c and see if that changes anything?

I have seen sporadic problems with the TOC edit phase on my own device, but have never managed to figure out the cause. I suspect that there's some kind of synchronization missing between the track and metadata write.

@Craige
Copy link
Author

Craige commented Feb 26, 2021

I thought for a second that might work. It worked the first time I wrote a track without problem or error, but the next track failed. Wiping the disk and starting from scratch with the first track again also failed.

First session, first track (success):

➜  netmdcli git:(master) ✗ ./netmdcli -v send ~/Desktop/track.wav
Net MD Walkman
Raw title: 
Disc Title: <Untitled>

audio file size : 39522976 bytes
supported audio file detected
data chunk position at 152
audio data size read from file :           39522816 bytes
audio data size calculated from file size: 39522816 bytes
netmd_acquire_dev: Unknown Error
netmd_secure_leave_session : No error
netmd_secure_set_track_protection : No error
netmd_secure_enter_session : No error
netmd_secure_send_key_data : No error
netmd_secure_session_key_exchange : No error
netmd_secure_setup_download : No error
generating packet 1 : 1048552 bytes
generating packet 2 : 1048576 bytes
generating packet 3 : 1048576 bytes
generating packet 4 : 1048576 bytes
generating packet 5 : 1048576 bytes
generating packet 6 : 1048576 bytes
generating packet 7 : 1048576 bytes
generating packet 8 : 1048576 bytes
generating packet 9 : 1048576 bytes
generating packet 10 : 1048576 bytes
generating packet 11 : 1048576 bytes
generating packet 12 : 1048576 bytes
generating packet 13 : 1048576 bytes
generating packet 14 : 1048576 bytes
generating packet 15 : 1048576 bytes
generating packet 16 : 1048576 bytes
generating packet 17 : 1048576 bytes
generating packet 18 : 1048576 bytes
generating packet 19 : 1048576 bytes
generating packet 20 : 1048576 bytes
generating packet 21 : 1048576 bytes
generating packet 22 : 1048576 bytes
generating packet 23 : 1048576 bytes
generating packet 24 : 1048576 bytes
generating packet 25 : 1048576 bytes
generating packet 26 : 1048576 bytes
generating packet 27 : 1048576 bytes
generating packet 28 : 1048576 bytes
generating packet 29 : 1048576 bytes
generating packet 30 : 1048576 bytes
generating packet 31 : 1048576 bytes
generating packet 32 : 1048576 bytes
generating packet 33 : 1048576 bytes
generating packet 34 : 1048576 bytes
generating packet 35 : 1048576 bytes
generating packet 36 : 1048576 bytes
generating packet 37 : 1048576 bytes
last packet: packet_data_length=725528 + frame_padding=1536 = chunksize=727064
generating packet 38 : 727064 bytes
netmd_prepare_packets : No error
total transfer size : 39524376 bytes, 19299 frames of 2048 bytes
1048576 of 39524376 bytes (2%) transferred (1048576 of 1048576 bytes in packet)
2097152 of 39524376 bytes (5%) transferred (1048576 of 1048576 bytes in packet)
3145728 of 39524376 bytes (7%) transferred (1048576 of 1048576 bytes in packet)
4194304 of 39524376 bytes (10%) transferred (1048576 of 1048576 bytes in packet)
5242880 of 39524376 bytes (13%) transferred (1048576 of 1048576 bytes in packet)
6291456 of 39524376 bytes (15%) transferred (1048576 of 1048576 bytes in packet)
7340032 of 39524376 bytes (18%) transferred (1048576 of 1048576 bytes in packet)
8388608 of 39524376 bytes (21%) transferred (1048576 of 1048576 bytes in packet)
9437184 of 39524376 bytes (23%) transferred (1048576 of 1048576 bytes in packet)
10485760 of 39524376 bytes (26%) transferred (1048576 of 1048576 bytes in packet)
11534336 of 39524376 bytes (29%) transferred (1048576 of 1048576 bytes in packet)
12582912 of 39524376 bytes (31%) transferred (1048576 of 1048576 bytes in packet)
13631488 of 39524376 bytes (34%) transferred (1048576 of 1048576 bytes in packet)
14680064 of 39524376 bytes (37%) transferred (1048576 of 1048576 bytes in packet)
15728640 of 39524376 bytes (39%) transferred (1048576 of 1048576 bytes in packet)
16777216 of 39524376 bytes (42%) transferred (1048576 of 1048576 bytes in packet)
17825792 of 39524376 bytes (45%) transferred (1048576 of 1048576 bytes in packet)
18874368 of 39524376 bytes (47%) transferred (1048576 of 1048576 bytes in packet)
19922944 of 39524376 bytes (50%) transferred (1048576 of 1048576 bytes in packet)
20971520 of 39524376 bytes (53%) transferred (1048576 of 1048576 bytes in packet)
22020096 of 39524376 bytes (55%) transferred (1048576 of 1048576 bytes in packet)
23068672 of 39524376 bytes (58%) transferred (1048576 of 1048576 bytes in packet)
24117248 of 39524376 bytes (61%) transferred (1048576 of 1048576 bytes in packet)
25165824 of 39524376 bytes (63%) transferred (1048576 of 1048576 bytes in packet)
26214400 of 39524376 bytes (66%) transferred (1048576 of 1048576 bytes in packet)
27262976 of 39524376 bytes (68%) transferred (1048576 of 1048576 bytes in packet)
28311552 of 39524376 bytes (71%) transferred (1048576 of 1048576 bytes in packet)
29360128 of 39524376 bytes (74%) transferred (1048576 of 1048576 bytes in packet)
30408704 of 39524376 bytes (76%) transferred (1048576 of 1048576 bytes in packet)
31457280 of 39524376 bytes (79%) transferred (1048576 of 1048576 bytes in packet)
32505856 of 39524376 bytes (82%) transferred (1048576 of 1048576 bytes in packet)
33554432 of 39524376 bytes (84%) transferred (1048576 of 1048576 bytes in packet)
34603008 of 39524376 bytes (87%) transferred (1048576 of 1048576 bytes in packet)
35651584 of 39524376 bytes (90%) transferred (1048576 of 1048576 bytes in packet)
36700160 of 39524376 bytes (92%) transferred (1048576 of 1048576 bytes in packet)
37748736 of 39524376 bytes (95%) transferred (1048576 of 1048576 bytes in packet)
38797312 of 39524376 bytes (98%) transferred (1048576 of 1048576 bytes in packet)
39524376 of 39524376 bytes (100%) transferred (727064 of 727064 bytes in packet)
netmd_transfer_song_packets : transfer took 112 seconds (344 kB/sec)
netmd_secure_send_track : No error
New Track: 0
netmd_secure_commit_track : No error
netmd_secure_session_key_forget : No error
netmd_secure_leave_session : No error
netmd_release_dev : Unknown Error

First session, second track (fail):

➜  netmdcli git:(master) ✗ ./netmdcli -v send ~/Desktop/track2.wav
Net MD Walkman
Raw title:
Disc Title: <Untitled>

audio file size : 40804020 bytes
supported audio file detected
data chunk position at 172
audio data size read from file :           40803840 bytes
audio data size calculated from file size: 40803840 bytes
netmd_acquire_dev: Unknown Error
netmd_secure_leave_session : No error
netmd_secure_set_track_protection : No error
netmd_secure_enter_session : No error
netmd_secure_send_key_data : No error
netmd_secure_session_key_exchange : No error
netmd_secure_setup_download : No error
generating packet 1 : 1048552 bytes
generating packet 2 : 1048576 bytes
generating packet 3 : 1048576 bytes
generating packet 4 : 1048576 bytes
generating packet 5 : 1048576 bytes
generating packet 6 : 1048576 bytes
generating packet 7 : 1048576 bytes
generating packet 8 : 1048576 bytes
generating packet 9 : 1048576 bytes
generating packet 10 : 1048576 bytes
generating packet 11 : 1048576 bytes
generating packet 12 : 1048576 bytes
generating packet 13 : 1048576 bytes
generating packet 14 : 1048576 bytes
generating packet 15 : 1048576 bytes
generating packet 16 : 1048576 bytes
generating packet 17 : 1048576 bytes
generating packet 18 : 1048576 bytes
generating packet 19 : 1048576 bytes
generating packet 20 : 1048576 bytes
generating packet 21 : 1048576 bytes
generating packet 22 : 1048576 bytes
generating packet 23 : 1048576 bytes
generating packet 24 : 1048576 bytes
generating packet 25 : 1048576 bytes
generating packet 26 : 1048576 bytes
generating packet 27 : 1048576 bytes
generating packet 28 : 1048576 bytes
generating packet 29 : 1048576 bytes
generating packet 30 : 1048576 bytes
generating packet 31 : 1048576 bytes
generating packet 32 : 1048576 bytes
generating packet 33 : 1048576 bytes
generating packet 34 : 1048576 bytes
generating packet 35 : 1048576 bytes
generating packet 36 : 1048576 bytes
generating packet 37 : 1048576 bytes
generating packet 38 : 1048576 bytes
last packet: packet_data_length=957976 + frame_padding=512 = chunksize=958488
generating packet 39 : 958488 bytes
netmd_prepare_packets : No error
total transfer size : 40804376 bytes, 19924 frames of 2048 bytes
1048576 of 40804376 bytes (2%) transferred (1048576 of 1048576 bytes in packet)
2097152 of 40804376 bytes (5%) transferred (1048576 of 1048576 bytes in packet)
3145728 of 40804376 bytes (7%) transferred (1048576 of 1048576 bytes in packet)
4194304 of 40804376 bytes (10%) transferred (1048576 of 1048576 bytes in packet)
5242880 of 40804376 bytes (12%) transferred (1048576 of 1048576 bytes in packet)
6291456 of 40804376 bytes (15%) transferred (1048576 of 1048576 bytes in packet)
7340032 of 40804376 bytes (17%) transferred (1048576 of 1048576 bytes in packet)
8388608 of 40804376 bytes (20%) transferred (1048576 of 1048576 bytes in packet)
9437184 of 40804376 bytes (23%) transferred (1048576 of 1048576 bytes in packet)
10485760 of 40804376 bytes (25%) transferred (1048576 of 1048576 bytes in packet)
11534336 of 40804376 bytes (28%) transferred (1048576 of 1048576 bytes in packet)
12582912 of 40804376 bytes (30%) transferred (1048576 of 1048576 bytes in packet)
13631488 of 40804376 bytes (33%) transferred (1048576 of 1048576 bytes in packet)
14680064 of 40804376 bytes (35%) transferred (1048576 of 1048576 bytes in packet)
15728640 of 40804376 bytes (38%) transferred (1048576 of 1048576 bytes in packet)
16777216 of 40804376 bytes (41%) transferred (1048576 of 1048576 bytes in packet)
17825792 of 40804376 bytes (43%) transferred (1048576 of 1048576 bytes in packet)
18874368 of 40804376 bytes (46%) transferred (1048576 of 1048576 bytes in packet)
19922944 of 40804376 bytes (48%) transferred (1048576 of 1048576 bytes in packet)
20971520 of 40804376 bytes (51%) transferred (1048576 of 1048576 bytes in packet)
22020096 of 40804376 bytes (53%) transferred (1048576 of 1048576 bytes in packet)
23068672 of 40804376 bytes (56%) transferred (1048576 of 1048576 bytes in packet)
24117248 of 40804376 bytes (59%) transferred (1048576 of 1048576 bytes in packet)
25165824 of 40804376 bytes (61%) transferred (1048576 of 1048576 bytes in packet)
26214400 of 40804376 bytes (64%) transferred (1048576 of 1048576 bytes in packet)
27262976 of 40804376 bytes (66%) transferred (1048576 of 1048576 bytes in packet)
28311552 of 40804376 bytes (69%) transferred (1048576 of 1048576 bytes in packet)
29360128 of 40804376 bytes (71%) transferred (1048576 of 1048576 bytes in packet)
30408704 of 40804376 bytes (74%) transferred (1048576 of 1048576 bytes in packet)
31457280 of 40804376 bytes (77%) transferred (1048576 of 1048576 bytes in packet)
32505856 of 40804376 bytes (79%) transferred (1048576 of 1048576 bytes in packet)
33554432 of 40804376 bytes (82%) transferred (1048576 of 1048576 bytes in packet)
34603008 of 40804376 bytes (84%) transferred (1048576 of 1048576 bytes in packet)
35651584 of 40804376 bytes (87%) transferred (1048576 of 1048576 bytes in packet)
36700160 of 40804376 bytes (89%) transferred (1048576 of 1048576 bytes in packet)
37748736 of 40804376 bytes (92%) transferred (1048576 of 1048576 bytes in packet)
38797312 of 40804376 bytes (95%) transferred (1048576 of 1048576 bytes in packet)
39845888 of 40804376 bytes (97%) transferred (1048576 of 1048576 bytes in packet)
40804376 of 40804376 bytes (100%) transferred (958488 of 958488 bytes in packet)
netmd_transfer_song_packets : transfer took 116 seconds (343 kB/sec)
netmd_secure_send_track : No error
New Track: 1
netmd_exch_message: netmd_poll failed
netmd_secure_commit_track failed : Unknown Error
netmd_secure_session_key_forget : No error
netmd_secure_leave_session : No error
netmd_release_dev : Unknown Error

Second session, first track (failed):

➜  netmdcli git:(master) ✗ ./netmdcli -v send ~/Desktop/track.wav
Net MD Walkman
Raw title:
Disc Title: <Untitled>

audio file size : 39522976 bytes
supported audio file detected
data chunk position at 152
audio data size read from file :           39522816 bytes
audio data size calculated from file size: 39522816 bytes
netmd_acquire_dev: Unknown Error
netmd_secure_leave_session : No error
netmd_secure_set_track_protection : No error
netmd_secure_enter_session : No error
netmd_secure_send_key_data : No error
netmd_secure_session_key_exchange : No error
netmd_secure_setup_download : No error
generating packet 1 : 1048552 bytes
generating packet 2 : 1048576 bytes
generating packet 3 : 1048576 bytes
generating packet 4 : 1048576 bytes
generating packet 5 : 1048576 bytes
generating packet 6 : 1048576 bytes
generating packet 7 : 1048576 bytes
generating packet 8 : 1048576 bytes
generating packet 9 : 1048576 bytes
generating packet 10 : 1048576 bytes
generating packet 11 : 1048576 bytes
generating packet 12 : 1048576 bytes
generating packet 13 : 1048576 bytes
generating packet 14 : 1048576 bytes
generating packet 15 : 1048576 bytes
generating packet 16 : 1048576 bytes
generating packet 17 : 1048576 bytes
generating packet 18 : 1048576 bytes
generating packet 19 : 1048576 bytes
generating packet 20 : 1048576 bytes
generating packet 21 : 1048576 bytes
generating packet 22 : 1048576 bytes
generating packet 23 : 1048576 bytes
generating packet 24 : 1048576 bytes
generating packet 25 : 1048576 bytes
generating packet 26 : 1048576 bytes
generating packet 27 : 1048576 bytes
generating packet 28 : 1048576 bytes
generating packet 29 : 1048576 bytes
generating packet 30 : 1048576 bytes
generating packet 31 : 1048576 bytes
generating packet 32 : 1048576 bytes
generating packet 33 : 1048576 bytes
generating packet 34 : 1048576 bytes
generating packet 35 : 1048576 bytes
generating packet 36 : 1048576 bytes
generating packet 37 : 1048576 bytes
last packet: packet_data_length=725528 + frame_padding=1536 = chunksize=727064
generating packet 38 : 727064 bytes
netmd_prepare_packets : No error
total transfer size : 39524376 bytes, 19299 frames of 2048 bytes
1048576 of 39524376 bytes (2%) transferred (1048576 of 1048576 bytes in packet)
2097152 of 39524376 bytes (5%) transferred (1048576 of 1048576 bytes in packet)
3145728 of 39524376 bytes (7%) transferred (1048576 of 1048576 bytes in packet)
4194304 of 39524376 bytes (10%) transferred (1048576 of 1048576 bytes in packet)
5242880 of 39524376 bytes (13%) transferred (1048576 of 1048576 bytes in packet)
6291456 of 39524376 bytes (15%) transferred (1048576 of 1048576 bytes in packet)
7340032 of 39524376 bytes (18%) transferred (1048576 of 1048576 bytes in packet)
8388608 of 39524376 bytes (21%) transferred (1048576 of 1048576 bytes in packet)
9437184 of 39524376 bytes (23%) transferred (1048576 of 1048576 bytes in packet)
10485760 of 39524376 bytes (26%) transferred (1048576 of 1048576 bytes in packet)
11534336 of 39524376 bytes (29%) transferred (1048576 of 1048576 bytes in packet)
12582912 of 39524376 bytes (31%) transferred (1048576 of 1048576 bytes in packet)
13631488 of 39524376 bytes (34%) transferred (1048576 of 1048576 bytes in packet)
14680064 of 39524376 bytes (37%) transferred (1048576 of 1048576 bytes in packet)
15728640 of 39524376 bytes (39%) transferred (1048576 of 1048576 bytes in packet)
16777216 of 39524376 bytes (42%) transferred (1048576 of 1048576 bytes in packet)
17825792 of 39524376 bytes (45%) transferred (1048576 of 1048576 bytes in packet)
18874368 of 39524376 bytes (47%) transferred (1048576 of 1048576 bytes in packet)
19922944 of 39524376 bytes (50%) transferred (1048576 of 1048576 bytes in packet)
20971520 of 39524376 bytes (53%) transferred (1048576 of 1048576 bytes in packet)
22020096 of 39524376 bytes (55%) transferred (1048576 of 1048576 bytes in packet)
23068672 of 39524376 bytes (58%) transferred (1048576 of 1048576 bytes in packet)
24117248 of 39524376 bytes (61%) transferred (1048576 of 1048576 bytes in packet)
25165824 of 39524376 bytes (63%) transferred (1048576 of 1048576 bytes in packet)
26214400 of 39524376 bytes (66%) transferred (1048576 of 1048576 bytes in packet)
27262976 of 39524376 bytes (68%) transferred (1048576 of 1048576 bytes in packet)
28311552 of 39524376 bytes (71%) transferred (1048576 of 1048576 bytes in packet)
29360128 of 39524376 bytes (74%) transferred (1048576 of 1048576 bytes in packet)
30408704 of 39524376 bytes (76%) transferred (1048576 of 1048576 bytes in packet)
31457280 of 39524376 bytes (79%) transferred (1048576 of 1048576 bytes in packet)
32505856 of 39524376 bytes (82%) transferred (1048576 of 1048576 bytes in packet)
33554432 of 39524376 bytes (84%) transferred (1048576 of 1048576 bytes in packet)
34603008 of 39524376 bytes (87%) transferred (1048576 of 1048576 bytes in packet)
35651584 of 39524376 bytes (90%) transferred (1048576 of 1048576 bytes in packet)
36700160 of 39524376 bytes (92%) transferred (1048576 of 1048576 bytes in packet)
37748736 of 39524376 bytes (95%) transferred (1048576 of 1048576 bytes in packet)
38797312 of 39524376 bytes (98%) transferred (1048576 of 1048576 bytes in packet)
39524376 of 39524376 bytes (100%) transferred (727064 of 727064 bytes in packet)
netmd_transfer_song_packets : transfer took 113 seconds (341 kB/sec)
netmd_secure_send_track : No error
New Track: 0
netmd_exch_message: netmd_poll failed
netmd_secure_commit_track failed : Unknown Error
netmd_secure_session_key_forget : No error
netmd_secure_leave_session : No error
netmd_release_dev : Unknown Error

A third write of the first track to a clean disk also failed, but is playable on the device. The device did get stuck in the Edit Toc loop, but seemed to break itself out of it about 30 seconds after the netmdcli process died. The device does take substantial (abnormal) time to read/buffer this track however.

@Craige
Copy link
Author

Craige commented Feb 27, 2021

I've narrowed it down. It doesn't appear to be related to TOC. It appears to happening during netmd_secure_commit_track().

A successful write:

New Track: 0
Command:
00 18 08 10 18 02 03 00                         		........
Response:
09 18 08 10 18 02 03 00                         		........
Command:
00 18 08 10 18 02 00 00                         		........
Response:
09 18 08 10 18 02 00 00                         		........
Command:
00 18 00 08 00 46 f0 03 01 03 48 ff 00 10 01 00 		.....F�...H�....
00 9c 32 0a 64 bc ef a1 7a                      		.�2.d��z
Response:
09 18 00 08 00 46 f0 03 01 03 48 00 00 10 01 00 		.....F�...H.....
00                                              		.
netmd_secure_commit_track : No error
Command:
00 18 00 08 00 46 f0 03 01 03 21 ff 00 00 00    		.....F�...!�...
Response:
09 18 00 08 00 46 f0 03 01 03 21 00 00 00 00    		.....F�...!....
netmd_secure_session_key_forget : No error
Command:
00 18 00 08 00 46 f0 03 01 03 81 ff             		.....F�...��
Response:
09 18 00 08 00 46 f0 03 01 03 81 00             		.....F�...�.
netmd_secure_leave_session : No error
Command:
00 ff 01 00 ff ff ff ff ff ff ff ff ff ff ff ff 		.�..������������

Response:
09 ff 01 00 ff ff ff ff ff ff ff ff ff ff ff ff 		.�..������������

netmd_release_dev : Unknown Error

And a failed one:

New Track: 2
Command:
00 18 08 10 18 02 03 00                         		........
Response:
09 18 08 10 18 02 03 00                         		........
Command:
00 18 08 10 18 02 00 00                         		........
Response:
09 18 08 10 18 02 00 00                         		........
Command:
00 18 00 08 00 46 f0 03 01 03 48 ff 00 10 01 00 		.....F�...H�....
02 8b 2c 5e f4 24 1b 9e ba                      		.�,^�$.��
netmd_exch_message: netmd_poll failed
netmd_secure_commit_track failed : Unknown Error
Command:
00 18 00 08 00 46 f0 03 01 03 21 ff 00 00 00    		.....F�...!�...
Response:
09 18 00 08 00 46 f0 03 01 03 21 00 00 00 00    		.....F�...!....
netmd_secure_session_key_forget : No error
Command:
00 18 00 08 00 46 f0 03 01 03 81 ff             		.....F�...��
Response:
09 18 00 08 00 46 f0 03 01 03 81 00             		.....F�...�.
netmd_secure_leave_session : No error
Command:
00 ff 01 00 ff ff ff ff ff ff ff ff ff ff ff ff 		.�..������������

Response:
09 ff 01 00 ff ff ff ff ff ff ff ff ff ff ff ff 		.�..������������

netmd_release_dev : Unknown Error

The 0x48 command is being sent, but on failed writes it doesn't seem to get a response. I'm not sure if it's a timing thing with the player. I've managed to write to write two successful tracks in a row, and then a third failed in the above manner. Then, on another attempt, the first write will experience the error.

I wondered if the player is busy and not listening to the serial channel when the command is sent until after netmdcli gives and gives up waiting for a response. But then again, the rest of the commands to close the session seem to go through, indicating the player must be listening to the serial connection. It seems to only be the 0x48 command, and only some times.

Any thoughts of where I could poke around further?

@vuori
Copy link
Owner

vuori commented Feb 27, 2021

The secure mode stuff is generally temperamental and pretty much anything can cause the player to crash, so I'm afraid I don't have any straightforward ideas. Since some tracks work, the cipher setup is probably correct, so it's likely that this is either a timing or alignment problem.

When writing to a blank disc, if you look at the line last packet: packet_data_length=957976 + frame_padding=512 = chunksize=958488 in th debug output, is there a difference in the value of frame_padding for a track that works vs. a track that crashes? For example, is it always 1536 for one that works and something else for one that doesn't?

@vuori
Copy link
Owner

vuori commented Feb 27, 2021

Sorry, I managed to miss that you had tried rewriting the same track to a blank disc already. It's unlikely that this is an alignment issue. So a timing issue looks likely. You might try to add the usleep calls suggested in this PR: https://github.com/vuori/linux-minidisc/pull/3/files and see if that helps.

Otherwise it may be necessary to set up Sonicstage somewhere and snoop its USB traffic to see what's happening between the end of track transfer and the track commit.

@Craige
Copy link
Author

Craige commented Feb 28, 2021

I tried the usleep in that thread to no avail. Also tried it in another few key places.

One thing that seemed to help was to increase NETMD_RECV_TRIES significantly in common.c, I've actually been able to write as many as 3 tracks without failure. I also printed out polling attempts at the top of the for loop in netmd_poll, and it indicated that the polling required to receive the 0x48 command response seems to go up almost exponentially for each additional track.

In the end, I'm beginning to wonder if it might just be a faulty player being the reason it's not seeming to respond in a timely manner when committing a track.

@vuori
Copy link
Owner

vuori commented Feb 28, 2021

#4 reported similar-ish issues related to what appears to be faulty device (Sonicstage couldn't write tracks either). If you can somehow try out Sonicstage that might provide conclusive evidence, but for least pain you'll need a 32-bit Windows XP/Vista/7 installation, so still quite a bit of pain.

But there's some good news: I grabbed a Sonicstage USB trace today and found two bugs in how the track title is written. From reading the massively baroque AV/C standards, these commands probably have never served much purpose because they mostly repeat stuff the device should already know, but some firmwares may expect to receive them [1]. I'll try to put together this week a version that fixes these.

If that doesn't solve the problem but you can Sonicstage working, a USB capture with your device may be informative. I can send you a working installer if needed.

[1] I wouldn't blame the firmware authors if they just assume that the computer sends a fixed sequence in commands. Implementing all of this bloated monstrosity in the 90s would have required a second Minidisc just for the firmware.

@vuori
Copy link
Owner

vuori commented Mar 1, 2021

Can you try the latest master and see if it improves anything?

The original idea turned out to be a red herring, the auxiliary write commands take a different destination address format than the actual write commands and were correct as-is. However, the netmd_wait_for_sync function was relying on potentally uninitialized data which may have caused operations to continue too soon. The sequence of writing operations should match Sonicstage pretty much exactly now, the only difference is that Sonicstage continuously spams the device with sync calls and status read commands.

Note that if the write is interrupted, the device will be left in a random state and usually pretty unhappy about it. It should be fully rebooted before trying again. I'm planning to work on error and interruption handling soon so that netmdcli will clean up after itself, but until then a new send is unlikely to work before a boot.

@Craige
Copy link
Author

Craige commented Mar 1, 2021

I think you may have it! I've officially written 4 tracks to a disk without error - the most I've been able to write so far.

I've also noticed that the required polling to get a 0x48 response is holding steady. It only polls 6 or 7 times now instead of going up exponentially for each track. In previous sends I saw tracks take upwards of 200 polls to get a response!

Edit: 6 tracks and counting it. I'm going to say that was the problem. Great job, and thank you!

Edit 2: Just for note, I wrote a 10 track EP to disk and observed that polling requests did in fact still creep up at times. Nowhere near like it used to. The last track had to poll about ~30 times before getting a response.

Not sure if this is expected, or something notable with just my player. Still, considering the current value of NETMD_RECV_TRIES is 30, I thought it might be worth mentioning. If it's not just my player, then perhaps that default should be bumped a little bit.

I THINK the number of polling requests might have a relationship to the number of tracks written to the disk in some capacity - maybe even just since the last restart/reconnect - but I'm not sure. Just thought it was note worthy.

@vuori
Copy link
Owner

vuori commented Mar 1, 2021

Good to hear that it's working at least to some degree. I pushed a refactoring commit which shouldn't change any functionality.

30 polling iterations sounds like a lot. There's not much downside to increasing the maximum, but it would be nice to know if there's something else that could be done. Have you tested with multiple discs?

@Craige
Copy link
Author

Craige commented Mar 1, 2021

I haven't tested with a second disk since your last update that appears to work without any actual failures.

I'll try to write another longer disk later today though and gather some more data on 0x48 response polling.

@vuori
Copy link
Owner

vuori commented Mar 3, 2021

If you write tracks until the polling slows down, then completely power off the device, then write a new track, does it still poll for a long time?

One possibility is that the device runs some housekeeping at each poll. If it doesn't get enough of them, there will be housekeeping tasks stuck in a queue. Sonicstage sends polling requests continuously so housekeeping would always happen, but netmdcli mostly sends them when it's waiting to hear something useful back.

@Craige
Copy link
Author

Craige commented Mar 3, 2021

Hey, sorry. I did try writing another disk the other day, and I was right back to square one again.

I think the difference that made it appear like everything was working after your change is I grabbed a disk I had only tried to write to once the previous day. The other two disks I had been attempting to write to were set aside.

Upon further inspection, the two disks I spent the most time writing to appear to be scratched on the top side. I'm not sure if it's the magnetic head scratching the disk or something else going on. Reading doesn't appear to scratch the disk. I can play for hours on old already written disks and they show no signs of scratching. I think your change did make a difference, because I was now able to write to a disk the first or second time without issue where as I wasn't able to write to the two other disks the first time without failure

These aren't new disks I'm working with, and truth be told opening up the slider they appear to be quite dusty. I know they were once used in quite a dusty environment before being retired.

I'm going to try to clean the remaining disks I have and try again. I have 2 disks that have yet to be written to since being pulled out of storage. Barring that, I may have to obtain some news disks to proceed any further.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants